Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Optionally log last known call, publish stacktrace in telemetry #3798

Merged
merged 11 commits into from Feb 15, 2022

Conversation

v0idpwn
Copy link
Member

@v0idpwn v0idpwn commented Dec 13, 2021

This PR is a response to elixir-ecto/ecto_sql#363 and elixir-ecto/ecto_sql#364.

Ecto SQL PR: elixir-ecto/ecto_sql#366

This is how logs will be displayed in Ecto SQL:

17:41:01.272 [debug] QUERY OK source="my_schema" db=2.7ms queue=0.1ms idle=985.4ms
DELETE FROM "my_schema" AS m0 []
↳ EctoBug.reproduce/1, at: [file: 'lib/ecto_bug.ex', line: 6]
 
17:41:01.275 [debug] QUERY OK db=3.2ms idle=965.0ms
INSERT INTO "my_schema" ("title","view_count") VALUES ($1,$2),($3,$4),($5,$6),($7,$8),($9,$10),($11,$12) ["sample", 1, "sample", 2, "sample", 3, "sample", 4, "sample", 5, "sample", 6]
↳ EctoBug.reproduce/1, at: [file: 'lib/ecto_bug.ex', line: 7]
 
17:41:01.277 [debug] QUERY OK source="my_schema" db=2.1ms idle=963.9ms
SELECT m0."id", m0."title", m0."view_count" FROM "public"."my_schema" AS m0 []
↳ EctoBug.reproduce/1, at: [file: 'lib/ecto_bug.ex', line: 16]
 
# Note this one doesn't show the exact repo call but the function that calls the function that does the repo call. This is
# due to underlying BEAM optimizations in tail calls
17:41:01.280 [debug] QUERY OK source="my_schema" db=2.5ms idle=955.0ms
SELECT m0."id", m0."title", m0."view_count" FROM "public"."my_schema" AS m0 WHERE (m0."view_count" > $1) AND (m0."view_count" >= $2) [3, 2]
↳ TaskRunner.handle_info/2, at: [file: 'lib/ecto_bug/application.ex', line: 10]

To enable this feature, one would need to put in the repo options:

config :my_app, MyApp.Repo, get_stacktrace?: true

If enabled, the stacktrace also gets published in its entirety in respective telemetry events. This should probably only be enabled in dev environment due to performance impact.

lib/ecto/repo.ex Outdated Show resolved Hide resolved
@v0idpwn v0idpwn requested a review from josevalim January 9, 2022 11:57
lib/ecto/repo.ex Outdated Show resolved Hide resolved
Comment on lines +59 to +61
* `:stacktrace`- publishes the stacktrace in telemetry events and
allows more advanced logging.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Its a bit of a gray area because, well, this is how ecto_sql uses it, but it may be used differently elsewhere :~

@@ -154,6 +154,29 @@ defmodule Ecto.Repo.Supervisor do
end
end

@compile {:inline, triplet: 2, maybe_put_stacktrace: 2}
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Since the triplet function is not used in this module the inline annotation has no effect - it only potentially inlines the function inside of the module (it works just fine for maybe_put_stacktrace though)

@josevalim josevalim merged commit 0cf1800 into elixir-ecto:master Feb 15, 2022
@josevalim
Copy link
Member

💚 💙 💜 💛 ❤️

@v0idpwn v0idpwn deleted the feat/log-last-known-call branch March 31, 2022 11:10
@gmile
Copy link
Contributor

gmile commented Sep 13, 2023

Hi, @v0idpwn! Are you using this feature in development, or in production too? If you're using it in production, would you mind sharing how are you storing the stacktraces for later analysis?

@v0idpwn
Copy link
Member Author

v0idpwn commented Sep 13, 2023

Hello, @gmile. Our intention here was improving development logs (paired with elixir-ecto/ecto_sql#366). For production environment, the existing approaches to trace and correlate queries with spans are usually more than enough in my experience. I don't know about how appsignal in particular does it, but with opentelemetry you will always be able to relate queries to calling code.

@gmile
Copy link
Contributor

gmile commented Sep 13, 2023

@v0idpwn well noted on improving development logs, thanks for making this possible!

but with opentelemetry you will always be able to relate queries to calling code

I am actively studying OpenTelemetry right now, but am failing to see an out-of-the-box (e.g. provided by a package + configuration) solution 🤔 Would you happen to have an example of how to configure Ecto + OpenTelemetry to make Ecto include Ecto stacktraces in spans? I have briefly looked into opentelemetry-ecto (specifically, this part), but it doesn't seem to be including into spans out of the box - it seems like some custom coding might be needed 🤔

@v0idpwn
Copy link
Member Author

v0idpwn commented Sep 13, 2023

@gmile it doesn't include the stacktrace, but it does include the "span-trace" (I mean the tree of spans that ran the query), which is generally better than a stack-trace for most cases, no?

@gmile
Copy link
Contributor

gmile commented Sep 13, 2023

@v0idpwn in the grand scheme of things, a tree of spans (together constituting, what I understand, what's known as a "a trace") is enough for most cases, I agree. But what I am looking for is more resolution, so to say. For example, I want to select a given span coming from Ecto, and be able to find the file/line that produced that span - as quickly as possible.

Basically, I want to do what another person was asking in original issue here elixir-ecto/ecto_sql#364, e.g. "I need the line number in the code", but available in production.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

4 participants